Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

FTP upload with TLS 1.3 results in 0 byte file on the server, eventually times out #13556

Open
blach opened this issue May 7, 2024 · 17 comments
Open

FTP upload with TLS 1.3 results in 0 byte file on the server, eventually times out #13556

blach opened this issue May 7, 2024 · 17 comments
Labels
FTP TLS

Comments

@blach
Copy link

blach commented May 7, 2024 •
edited

I did this

I'm using the following command line to upload the file "test.html" with a size of 18815 bytes to a server using FTP with SSL encryption:

curl --ssl-reqd ftp://<redacted>.kasserver.com/test/ -u <redacted> --upload-file test.html

This command results in a 0 byte file on the server instead of the expected file with 18815 bytes.

The transfer progress looks like this:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 18815    0     0  100 18815      0    311  0:01:00  0:01:00 --:--:--     0
curl: (28) FTP response timeout

It claims that 18815 bytes are transferred immediately, but then nothing happens and the upload times out after 1 minute.

When I add --tls-max 1.2, the upload works immediately and the file on the server has the correct size and contents.

This is the FTP server of the popular German hoster https://all-inkl.com/

I expected the following

I expected the file to upload successfully.

curl/libcurl version

curl 8.7.1 (aarch64-apple-darwin23.4.0) libcurl/8.7.1 (SecureTransport) OpenSSL/3.3.0 zlib/1.2.12 brotli/1.1.0 zstd/1.5.6 libidn2/2.3.7 libssh2/1.11.0 nghttp2/1.61.0 librtmp/2.3 OpenLDAP/2.6.7
Release-Date: 2024-03-27
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

operating system

macOS Sonoma 14.4.1
@blach
Copy link
Author

blach commented May 7, 2024 •
edited

This is the verbose output of the failing FTP upload command that eventually times out and results in a 0 byte file on the server:

* Connected to <redacted>.kasserver.com (85.13.<redacted>) port 21
< 220 FTP on <redacted>.kasserver.com ready
> AUTH SSL
< 234 AUTH SSL successful
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [88 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [155 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [10 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [4590 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [264 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / secp256r1 / RSASSA-PSS
* Server certificate:
*  subject: CN=*.kasserver.com
*  start date: Dec 18 00:00:00 2023 GMT
*  expire date: Jan 17 23:59:59 2025 GMT
*  subjectAltName: host "<redacted>.kasserver.com" matched cert's "*.kasserver.com"
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
*   Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
*   Certificate level 1: Public key type RSA (2048/112 Bits/secBits), signed using sha384WithRSAEncryption
*   Certificate level 2: Public key type RSA (4096/152 Bits/secBits), signed using sha384WithRSAEncryption
} [5 bytes data]
> USER <redacted>
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [57 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [57 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
< 331 Password required for <redacted>
} [5 bytes data]
> PASS <redacted>
{ [5 bytes data]
< 230 User <redacted> logged in
} [5 bytes data]
> PBSZ 0
{ [5 bytes data]
< 200 PBSZ 0 successful
} [5 bytes data]
> PROT P
{ [5 bytes data]
< 200 Protection set to Private
} [5 bytes data]
> PWD
{ [5 bytes data]
< 257 "/" is the current directory
* Entry path is '/'
} [5 bytes data]
> CWD test
* ftp_perform ends with SECONDARY: 0
{ [5 bytes data]
< 250 CWD command successful
} [5 bytes data]
> EPSV
* Connect data stream passively
{ [5 bytes data]
< 229 Entering Extended Passive Mode (|||50218|)
* Connecting to 85.13.<redacted> (85.13.<redacted>) port 50218
*   Trying 85.13.<redacted>:50218...
* Connected 2nd connection to 85.13.<redacted> port 50218
* SSL reusing session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
> TYPE I
{ [5 bytes data]
< 200 Type set to I
} [5 bytes data]
> STOR test.html
{ [5 bytes data]
< 150 Opening BINARY mode data connection for test.html
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [88 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [161 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [10 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / secp256r1 / UNDEF
* Server certificate:
*  subject: CN=*.kasserver.com
*  start date: Dec 18 00:00:00 2023 GMT
*  expire date: Jan 17 23:59:59 2025 GMT
*  subjectAltName: host "<redacted>.kasserver.com" matched cert's "*.kasserver.com"
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=Sectigo Limited; CN=Sectigo RSA Domain Validation Secure Server CA
*  SSL certificate verify ok.
} [5 bytes data]
* upload completely sent off: 18815 bytes
* Remembering we are in dir "test/"
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* FTP response timeout
* control connection looks dead
* Closing connection
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]

@blach
Copy link
Author

blach commented May 7, 2024

The problem might be related to #6149

This issue was actually discovered when using libcurl to upload a file >18KB using FTP with explicit auth SSL to that server.

With libcurl and curl_easy_perform I get the error "Transferred a partial file".

@blach
Copy link
Author

blach commented May 8, 2024 •
edited

I just set up a brand new vsftpd server on a Debian 12 machine that is publicly accessible.

I created a new RSA 4096 key and enabled SSL for the FTP server.

Now uploading a file larger than a certain size results in a 0 byte file on the server and the curl command times out.

Can I privately share the commands to reproduce this issue with you?

The problem is that the command only works once, then vsftp seems to keep accessing the file, so when the command is issued a second time, it shows a different behavior. That's why I wouldn't want to post this publicly.

@blach
Copy link
Author

blach commented May 8, 2024

The redacted commands to reproduce this after setting up the vsftpd server with SSL are:

To create a local file with a size of 18 kB:

head --bytes 18432 /dev/zero > test-curl.txt

Upload the file:

curl --ssl-reqd --insecure ftp://<ip-address>/ -u <redacted> --upload-file test-curl.txt --verbose

The upload starts, times out, and results in a 0 byte "test-curl.txt" file on the server.

Uploading the same file to the same server with FileZilla using TLS 1.3 works without problems.

@blach
Copy link
Author

blach commented May 8, 2024

I also asked the support team at all-inkl.com what FTP server software they are using. They answered that they are using ProFTPD from the original Ubuntu repository.

So it looks like this is an issue with both vsftpd and ProFTPD servers when using TLS 1.3.

@blach
Copy link
Author

blach commented May 20, 2024

Can you reproduce this issue? Is there anything I can do to help?

@bagder
Copy link
Member

bagder commented May 20, 2024

@icing there's no upload among the new ftp tests yet is there?

@icing
Copy link
Contributor

icing commented May 20, 2024 •
edited

Added --upload-file tests in #13734. I see no problems with a local vsftpd with or without --ssl-reqd. TLSv1.3 is being used. I tested on my macOS machine using my own vsftpd build (homebrew one is not linked with openssl). Let's see what the CI jobs on other platforms say on the PR.

@blach could you add -v --trace-config ids,time,tcp,read and tell use what gets logged?

icing added a commit to icing/curl that referenced this issue May 21, 2024
@icing
pytest, add ftp upload tests
c91ef2f 
- refs curl#13556
- allow anon uploads on vsftpd test server
- add test_30_05 for plain upload of 1k, 100k, 1m
- add test_31_05 for SSL upload of 1k, 100k, 1m
- verify file size and contents
@icing icing mentioned this issue May 21, 2024
Closed
@icing
Copy link
Contributor

icing commented May 21, 2024

Another thing to test with you vsftpd is if the setting require_ssl_reuse=NO makes any difference.

@blach
Copy link
Author

blach commented May 21, 2024

I just added require_ssl_reuse=NO to /etc/vsftpd.conf, restarted the vsftpd service and ran the upload command again.

I see no difference in behavior. It still results in a 0 byte file on the server and a timeout of the upload.

@blach
Copy link
Author

blach commented May 21, 2024 •
edited

@blach could you add -v --trace-config ids,time,tcp,read and tell use what gets logged?

Here is the log:

> curl --ssl-reqd --insecure ftp://<ipaddress>/ -u demo:<redacted> --upload-file test-curl.txt -v --trace-config ids,time,tcp,read
13:25:34.785068 [0-0] *   Trying <ipaddress>:21...
13:25:34.785332 [0-0] * [TCP] cf_socket_open() -> 0, fd=6
13:25:34.785477 [0-0] * [TCP] local address 192.168.2.169 port 50977...
13:25:34.785502 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
13:25:34.785524 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
13:25:34.785548 [0-0] * [TCP] not connected yet
13:25:34.785569 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
13:25:34.785590 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=6
13:25:34.803875 [0-0] * [TCP] connected
13:25:34.803908 [0-0] * Connected to <ipaddress> (<ipaddress>) port 21
13:25:34.824553 [0-0] * [TCP] nw_in_read(len=900, fd=6) -> 20, err=0
13:25:34.824587 [0-0] * [TCP] recv(len=900) -> 20, err=0
13:25:34.824612 [0-0] < 220 (vsFTPd 3.0.3)
13:25:34.824711 [0-0] * [TCP] send(len=10) -> 10, err=0
13:25:34.824736 [0-0] > AUTH SSL
13:25:34.839978 [0-0] * [TCP] nw_in_read(len=900, fd=6) -> 31, err=0
13:25:34.840011 [0-0] * [TCP] recv(len=900) -> 31, err=0
13:25:34.840038 [0-0] < 234 Proceed with negotiation.
13:25:34.843937 [0-0] } [5 bytes data]
13:25:34.843979 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
13:25:34.844003 [0-0] } [512 bytes data]
13:25:34.844072 [0-0] * [TCP] send(len=517) -> 517, err=0
13:25:34.844104 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
13:25:34.844127 [0-0] * [TCP] recv(len=5) -> -1, err=81
13:25:34.862637 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.862674 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.862700 [0-0] { [5 bytes data]
13:25:34.862748 [0-0] * [TCP] nw_in_read(len=88, fd=6) -> 88, err=0
13:25:34.862775 [0-0] * [TCP] recv(len=88) -> 88, err=0
13:25:34.862807 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
13:25:34.862833 [0-0] { [88 bytes data]
13:25:34.862903 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
13:25:34.862930 [0-0] } [1 bytes data]
13:25:34.863129 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
13:25:34.863159 [0-0] } [512 bytes data]
13:25:34.863257 [0-0] * [TCP] send(len=523) -> 523, err=0
13:25:34.863290 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.863317 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.863344 [0-0] { [5 bytes data]
13:25:34.863387 [0-0] * [TCP] nw_in_read(len=1, fd=6) -> 1, err=0
13:25:34.863415 [0-0] * [TCP] recv(len=1) -> 1, err=0
13:25:34.863443 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
13:25:34.863469 [0-0] * [TCP] recv(len=5) -> -1, err=81
13:25:34.899315 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.899364 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.899391 [0-0] { [5 bytes data]
13:25:34.899435 [0-0] * [TCP] nw_in_read(len=155, fd=6) -> 155, err=0
13:25:34.899461 [0-0] * [TCP] recv(len=155) -> 155, err=0
13:25:34.899495 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
13:25:34.899521 [0-0] { [155 bytes data]
13:25:34.899996 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.900025 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.900050 [0-0] { [5 bytes data]
13:25:34.900098 [0-0] * [TCP] nw_in_read(len=23, fd=6) -> 23, err=0
13:25:34.900124 [0-0] * [TCP] recv(len=23) -> 23, err=0
13:25:34.900157 [0-0] { [1 bytes data]
13:25:34.900200 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
13:25:34.900226 [0-0] { [6 bytes data]
13:25:34.900273 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.900299 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.900326 [0-0] { [5 bytes data]
13:25:34.900368 [0-0] * [TCP] nw_in_read(len=62, fd=6) -> 62, err=0
13:25:34.900395 [0-0] * [TCP] recv(len=62) -> 62, err=0
13:25:34.900423 [0-0] { [1 bytes data]
13:25:34.900464 [0-0] * TLSv1.3 (IN), TLS handshake, Request CERT (13):
13:25:34.900490 [0-0] { [45 bytes data]
13:25:34.900544 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.900570 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.900596 [0-0] { [5 bytes data]
13:25:34.900637 [0-0] * [TCP] nw_in_read(len=1411, fd=6) -> 1411, err=0
13:25:34.900662 [0-0] * [TCP] recv(len=1411) -> 1411, err=0
13:25:34.900695 [0-0] { [1 bytes data]
13:25:34.900740 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
13:25:34.900767 [0-0] { [1394 bytes data]
13:25:34.902005 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.902037 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.902064 [0-0] { [5 bytes data]
13:25:34.902112 [0-0] * [TCP] nw_in_read(len=537, fd=6) -> 537, err=0
13:25:34.902139 [0-0] * [TCP] recv(len=537) -> 537, err=0
13:25:34.902170 [0-0] { [1 bytes data]
13:25:34.902213 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
13:25:34.902240 [0-0] { [520 bytes data]
13:25:34.902488 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.902516 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.902542 [0-0] { [5 bytes data]
13:25:34.902589 [0-0] * [TCP] nw_in_read(len=69, fd=6) -> 69, err=0
13:25:34.902615 [0-0] * [TCP] recv(len=69) -> 69, err=0
13:25:34.902643 [0-0] { [1 bytes data]
13:25:34.902693 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
13:25:34.902719 [0-0] { [52 bytes data]
13:25:34.902830 [0-0] * TLSv1.3 (OUT), TLS handshake, Certificate (11):
13:25:34.902857 [0-0] } [8 bytes data]
13:25:34.902905 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
13:25:34.902932 [0-0] } [52 bytes data]
13:25:34.903088 [0-0] * [TCP] send(len=104) -> 104, err=0
13:25:34.903149 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / secp256r1 / RSASSA-PSS
13:25:34.903180 [0-0] * Server certificate:
13:25:34.903212 [0-0] *  subject: C=DE; ST=Some-State; L=Test; O=Test
13:25:34.903242 [0-0] *  start date: May  8 16:40:22 2024 GMT
13:25:34.903271 [0-0] *  expire date: May  6 16:40:22 2034 GMT
13:25:34.903300 [0-0] *  issuer: C=DE; ST=Some-State; L=Test; O=Test
13:25:34.903328 [0-0] *  SSL certificate verify result: self-signed certificate (18), continuing anyway.
13:25:34.903359 [0-0] *   Certificate level 0: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
13:25:34.903408 [0-0] } [5 bytes data]
13:25:34.903473 [0-0] * [TCP] send(len=33) -> 33, err=0
13:25:34.903499 [0-0] > USER demo
13:25:34.917653 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.917688 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.917715 [0-0] { [5 bytes data]
13:25:34.917758 [0-0] * [TCP] nw_in_read(len=250, fd=6) -> 250, err=0
13:25:34.917785 [0-0] * [TCP] recv(len=250) -> 250, err=0
13:25:34.917815 [0-0] { [1 bytes data]
13:25:34.917862 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
13:25:34.917889 [0-0] { [233 bytes data]
13:25:34.917954 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.917980 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.918006 [0-0] { [5 bytes data]
13:25:34.918046 [0-0] * [TCP] nw_in_read(len=250, fd=6) -> 250, err=0
13:25:34.918073 [0-0] * [TCP] recv(len=250) -> 250, err=0
13:25:34.918101 [0-0] { [1 bytes data]
13:25:34.918145 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
13:25:34.918171 [0-0] { [233 bytes data]
13:25:34.918220 [0-0] * old SSL session ID is stale, removing
13:25:34.918252 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.918279 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.918306 [0-0] { [5 bytes data]
13:25:34.918348 [0-0] * [TCP] nw_in_read(len=51, fd=6) -> 51, err=0
13:25:34.918374 [0-0] * [TCP] recv(len=51) -> 51, err=0
13:25:34.918401 [0-0] { [1 bytes data]
13:25:34.918444 [0-0] < 331 Please specify the password.
13:25:34.918480 [0-0] } [5 bytes data]
13:25:34.918563 [0-0] * [TCP] send(len=33) -> 33, err=0
13:25:34.918592 [0-0] > PASS <redacted>
13:25:34.987728 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:34.987807 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:34.987845 [0-0] { [5 bytes data]
13:25:34.987911 [0-0] * [TCP] nw_in_read(len=40, fd=6) -> 40, err=0
13:25:34.987948 [0-0] * [TCP] recv(len=40) -> 40, err=0
13:25:34.988021 [0-0] { [1 bytes data]
13:25:34.988161 [0-0] < 230 Login successful.
13:25:34.988590 [0-0] } [5 bytes data]
13:25:34.988737 [0-0] * [TCP] send(len=30) -> 30, err=0
13:25:34.988844 [0-0] > PBSZ 0
13:25:35.002428 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.002519 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.002556 [0-0] { [5 bytes data]
13:25:35.002620 [0-0] * [TCP] nw_in_read(len=37, fd=6) -> 37, err=0
13:25:35.002656 [0-0] * [TCP] recv(len=37) -> 37, err=0
13:25:35.002707 [0-0] { [1 bytes data]
13:25:35.002764 [0-0] < 200 PBSZ set to 0.
13:25:35.002813 [0-0] } [5 bytes data]
13:25:35.002927 [0-0] * [TCP] send(len=30) -> 30, err=0
13:25:35.002964 [0-0] > PROT P
13:25:35.020002 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.020069 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.020106 [0-0] { [5 bytes data]
13:25:35.020166 [0-0] * [TCP] nw_in_read(len=40, fd=6) -> 40, err=0
13:25:35.020202 [0-0] * [TCP] recv(len=40) -> 40, err=0
13:25:35.020249 [0-0] { [1 bytes data]
13:25:35.020307 [0-0] < 200 PROT now Private.
13:25:35.020355 [0-0] } [5 bytes data]
13:25:35.020470 [0-0] * [TCP] send(len=27) -> 27, err=0
13:25:35.020572 [0-0] > PWD
13:25:35.034769 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.034812 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.034843 [0-0] { [5 bytes data]
13:25:35.034896 [0-0] * [TCP] nw_in_read(len=60, fd=6) -> 60, err=0
13:25:35.034928 [0-0] * [TCP] recv(len=60) -> 60, err=0
13:25:35.034964 [0-0] { [1 bytes data]
13:25:35.035013 [0-0] < 257 "/home/demo" is the current directory
13:25:35.035048 [0-0] * Entry path is '/home/demo'
13:25:35.035082 [0-0] * Request has same path as previous transfer
13:25:35.035120 [0-0] } [5 bytes data]
13:25:35.035210 [0-0] * [TCP] send(len=28) -> 28, err=0
13:25:35.035242 [0-0] > EPSV
13:25:35.035272 [0-0] * Connect data stream passively
13:25:35.035307 [0-0] * ftp_perform ends with SECONDARY: 0
13:25:35.050290 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.050336 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.050376 [0-0] { [5 bytes data]
13:25:35.050443 [0-0] * [TCP] nw_in_read(len=65, fd=6) -> 65, err=0
13:25:35.050481 [0-0] * [TCP] recv(len=65) -> 65, err=0
13:25:35.050526 [0-0] { [1 bytes data]
13:25:35.050587 [0-0] < 229 Entering Extended Passive Mode (|||57503|)
13:25:35.051398 [0-0] * Connecting to <ipaddress> (<ipaddress>) port 57503
13:25:35.051499 [0-0] *   Trying <ipaddress>:57503...
13:25:35.051564 [0-0] * [TCP-1] cf_socket_open() -> 0, fd=7
13:25:35.051730 [0-0] * [TCP-1] local address 192.168.2.169 port 50978...
13:25:35.051775 [0-0] * [TCP-1] adjust_pollset, !connected, POLLOUT fd=7
13:25:35.051816 [0-0] * [TCP-1] adjust_pollset, !connected, POLLOUT fd=7
13:25:35.051862 [0-0] * [TCP-1] not connected yet
13:25:35.051901 [0-0] * [TCP-1] adjust_pollset, !connected, POLLOUT fd=7
13:25:35.051940 [0-0] * [TCP-1] adjust_pollset, !connected, POLLOUT fd=7
13:25:35.068188 [0-0] * [TCP-1] connected
13:25:35.068283 [0-0] * Connected 2nd connection to <ipaddress> port 57503
13:25:35.071746 [0-0] * SSL reusing session ID
13:25:35.072515 [0-0] } [5 bytes data]
13:25:35.072579 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
13:25:35.072617 [0-0] } [565 bytes data]
13:25:35.073082 [0-0] * [TCP-1] send(len=570) -> 570, err=0
13:25:35.073140 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> -1, err=81
13:25:35.073176 [0-0] * [TCP-1] recv(len=5) -> -1, err=81
13:25:35.073256 [0-0] } [5 bytes data]
13:25:35.073356 [0-0] * [TCP] send(len=30) -> 30, err=0
13:25:35.073393 [0-0] > TYPE I
13:25:35.087859 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> -1, err=81
13:25:35.087945 [0-0] * [TCP-1] recv(len=5) -> -1, err=81
13:25:35.088041 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.088089 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.088139 [0-0] { [5 bytes data]
13:25:35.088221 [0-0] * [TCP] nw_in_read(len=48, fd=6) -> 48, err=0
13:25:35.088327 [0-0] * [TCP] recv(len=48) -> 48, err=0
13:25:35.088406 [0-0] { [1 bytes data]
13:25:35.088478 [0-0] < 200 Switching to Binary mode.
13:25:35.088561 [0-0] } [5 bytes data]
13:25:35.089104 [0-0] * [TCP] send(len=42) -> 42, err=0
13:25:35.089153 [0-0] > STOR test-curl.txt
13:25:35.103656 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> 5, err=0
13:25:35.103718 [0-0] * [TCP-1] recv(len=5) -> 5, err=0
13:25:35.103755 [0-0] { [5 bytes data]
13:25:35.103816 [0-0] * [TCP-1] nw_in_read(len=88, fd=7) -> 88, err=0
13:25:35.103853 [0-0] * [TCP-1] recv(len=88) -> 88, err=0
13:25:35.103902 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
13:25:35.103937 [0-0] { [88 bytes data]
13:25:35.104218 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
13:25:35.104257 [0-0] } [1 bytes data]
13:25:35.104995 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
13:25:35.105102 [0-0] } [598 bytes data]
13:25:35.105233 [0-0] * [TCP-1] send(len=609) -> 609, err=0
13:25:35.105276 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> 5, err=0
13:25:35.105313 [0-0] * [TCP-1] recv(len=5) -> 5, err=0
13:25:35.105350 [0-0] { [5 bytes data]
13:25:35.105408 [0-0] * [TCP-1] nw_in_read(len=1, fd=7) -> 1, err=0
13:25:35.105462 [0-0] * [TCP-1] recv(len=1) -> 1, err=0
13:25:35.105500 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> -1, err=81
13:25:35.105535 [0-0] * [TCP-1] recv(len=5) -> -1, err=81
13:25:35.105586 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> 5, err=0
13:25:35.105621 [0-0] * [TCP] recv(len=5) -> 5, err=0
13:25:35.105655 [0-0] { [5 bytes data]
13:25:35.105740 [0-0] * [TCP] nw_in_read(len=39, fd=6) -> 39, err=0
13:25:35.105776 [0-0] * [TCP] recv(len=39) -> 39, err=0
13:25:35.105842 [0-0] { [1 bytes data]
13:25:35.105897 [0-0] < 150 Ok to send data.
13:25:35.120733 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> 5, err=0
13:25:35.120810 [0-0] * [TCP-1] recv(len=5) -> 5, err=0
13:25:35.120847 [0-0] { [5 bytes data]
13:25:35.120902 [0-0] * [TCP-1] nw_in_read(len=161, fd=7) -> 161, err=0
13:25:35.120933 [0-0] * [TCP-1] recv(len=161) -> 161, err=0
13:25:35.120989 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
13:25:35.121018 [0-0] { [161 bytes data]
13:25:35.122061 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> 5, err=0
13:25:35.122109 [0-0] * [TCP-1] recv(len=5) -> 5, err=0
13:25:35.122138 [0-0] { [5 bytes data]
13:25:35.122189 [0-0] * [TCP-1] nw_in_read(len=23, fd=7) -> 23, err=0
13:25:35.122218 [0-0] * [TCP-1] recv(len=23) -> 23, err=0
13:25:35.122262 [0-0] { [1 bytes data]
13:25:35.122308 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
13:25:35.122337 [0-0] { [6 bytes data]
13:25:35.122390 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> 5, err=0
13:25:35.122419 [0-0] * [TCP-1] recv(len=5) -> 5, err=0
13:25:35.122447 [0-0] { [5 bytes data]
13:25:35.122496 [0-0] * [TCP-1] nw_in_read(len=69, fd=7) -> 69, err=0
13:25:35.122525 [0-0] * [TCP-1] recv(len=69) -> 69, err=0
13:25:35.122558 [0-0] { [1 bytes data]
13:25:35.122614 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
13:25:35.122643 [0-0] { [52 bytes data]
13:25:35.122775 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
13:25:35.122804 [0-0] } [52 bytes data]
13:25:35.122987 [0-0] * [TCP-1] send(len=74) -> 74, err=0
13:25:35.123386 [0-0] * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 / secp256r1 / UNDEF
13:25:35.123421 [0-0] * Server certificate:
13:25:35.123590 [0-0] *  subject: C=DE; ST=Some-State; L=Test; O=Test
13:25:35.123631 [0-0] *  start date: May  8 16:40:22 2024 GMT
13:25:35.123661 [0-0] *  expire date: May  6 16:40:22 2034 GMT
13:25:35.123695 [0-0] *  issuer: C=DE; ST=Some-State; L=Test; O=Test
13:25:35.123730 [0-0] *  SSL certificate verify result: self-signed certificate (18), continuing anyway.
13:25:35.123778 [0-0] *   Certificate level 0: Public key type RSA (4096/152 Bits/secBits), signed using sha256WithRSAEncryption
13:25:35.125499 [0-0] } [5 bytes data]
13:25:35.125728 [0-0] * [TCP-1] send(len=16406) -> 16406, err=0
13:25:35.125776 [0-0] } [5 bytes data]
13:25:35.125844 [0-0] * [TCP-1] send(len=2070) -> 2070, err=0
13:25:35.125882 [0-0] } [18432 bytes data]
13:25:35.125949 [0-0] * upload completely sent off: 18432 bytes
13:25:35.125995 [0-0] * Remembering we are in dir ""
13:25:35.126044 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> -1, err=81
13:25:35.126084 [0-0] * [TCP-1] recv(len=5) -> -1, err=81
13:25:35.126128 [0-0] } [5 bytes data]
13:25:35.126194 [0-0] * [TCP-1] send(len=24) -> 24, err=0
13:25:35.126235 [0-0] * TLSv1.3 (OUT), TLS alert, close notify (256):
13:25:35.126273 [0-0] } [2 bytes data]
13:25:35.126334 [0-0] * [TCP-1] nw_in_read(len=5, fd=7) -> -1, err=81
13:25:35.126372 [0-0] * [TCP-1] recv(len=5) -> -1, err=81
13:25:35.126463 [0-0] * [TCP-1] cf_socket_close(7)
13:25:35.126517 [0-0] * [TCP-1] destroy
13:25:35.126563 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
13:25:35.126601 [0-0] * [TCP] recv(len=5) -> -1, err=81
100 18432    0     0  100 18432      0    305  0:01:00  0:01:00 --:--:--     013:26:35.132407 [0-0] * FTP response timeout
13:26:35.132514 [0-0] * control connection looks dead
100 18432    0     0  100 18432      0    305  0:01:00  0:01:00 --:--:--     0
13:26:35.132831 [0-0] * Closing connection
13:26:35.132977 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
13:26:35.133041 [0-0] * [TCP] recv(len=5) -> -1, err=81
13:26:35.133133 [0-0] } [5 bytes data]
13:26:35.133487 [0-0] * [TCP] send(len=24) -> 24, err=0
13:26:35.133561 [0-0] * TLSv1.3 (OUT), TLS alert, close notify (256):
13:26:35.133622 [0-0] } [2 bytes data]
13:26:35.133735 [0-0] * [TCP] nw_in_read(len=5, fd=6) -> -1, err=81
13:26:35.133800 [0-0] * [TCP] recv(len=5) -> -1, err=81
13:26:35.134044 [0-0] * [TCP] cf_socket_close(6)
13:26:35.134316 [0-0] * [TCP] destroy
curl: (28) FTP response timeout

@blach
Copy link
Author

blach commented May 21, 2024 •
edited

Some additional details:

I just tried running the curl command on the server that runs the vsftpd server.
The server runs Debian 12.5 Bookworm which comes with curl 7.88.1.

Curl 7.88.1 on the Debian server also resulted in a timeout and a 0 byte file.

Then I installed curl 8.7.1 from bookworm backports.

This version uploads the file to the vsftpd server running on the same server successfully!

So, curl 8.7.1 from Homebrew on my Mac shows the error while curl 8.7.1 on Debian does not show the error.

On my Mac:

curl 8.7.1 (aarch64-apple-darwin23.4.0) libcurl/8.7.1 (SecureTransport) OpenSSL/3.3.0 zlib/1.2.12 brotli/1.1.0 zstd/1.5.6 libidn2/2.3.7 libssh2/1.11.0 nghttp2/1.61.0 librtmp/2.3 OpenLDAP/2.6.7
Release-Date: 2024-03-27
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

On the Debian server:

curl 8.7.1 (x86_64-pc-linux-gnu) libcurl/8.7.1 OpenSSL/3.0.11 zlib/1.2.13 brotli/1.0.9 zstd/1.5.4 libidn2/2.3.3 libpsl/0.21.2 libssh2/1.10.0 nghttp2/1.52.0 librtmp/2.3 OpenLDAP/2.5.13
Release-Date: 2024-03-27, security patched: 8.7.1-5~bpo12+1
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

@blach
Copy link
Author

blach commented May 21, 2024

Could this be an aarch64 vs x86_64 architecture issue?

@icing
Copy link
Contributor

icing commented May 21, 2024

@blach I suspect more a timing issue. TLS has this concept of close notify messages at the end of a connection from both sides. That can make life tricky.

When ending the transfer, curl is sending close notify, checks if there is something from the server and then closes the socket. When the delay between curl and the server is large enough, the server might get an error sending his part of the TLS shutdown. Ideally, curl would be more gracefully here and wait a considerable time for the server to properly deliver his shutdown before closing the socket.

If you enable the following on your vsftp setup, we might see in the server log what it complains about:

xferlog_enable=YES
debug_ssl=YES
xferlog_std_format=NO

You can set vsftpd_log_file=path_to_my_log_file if you want it in another location. Default should be /var/log/vsftpd.log.

@blach
Copy link
Author

blach commented May 21, 2024

Thanks, I added those configuration options and see this in the log file:

Tue May 21 12:45:14 2024 [pid 254883] CONNECT: Client "::ffff:217.82.60.116"
Tue May 21 12:45:14 2024 [pid 254883] DEBUG: Client "::ffff:217.82.60.116", "SSL version: TLSv1.3, SSL cipher: TLS_AES_256_GCM_SHA384, not reused, no cert"
Tue May 21 12:45:14 2024 [pid 254882] [demo] OK LOGIN: Client "::ffff:217.82.60.116"
Tue May 21 12:45:14 2024 [pid 254883] [demo] DEBUG: Client "::ffff:217.82.60.116", "SSL version: TLSv1.3, SSL cipher: TLS_AES_256_GCM_SHA384, reused, no cert"
Tue May 21 12:50:14 2024 [pid 254883] [demo] DEBUG: Client "::ffff:217.82.60.116", "DATA connection terminated without SSL shutdown. Buggy client! Integrity of upload cannot be asserted."
Tue May 21 12:50:14 2024 [pid 254883] [demo] DEBUG: Client "::ffff:217.82.60.116", "SSL shutdown state is: NONE"
Tue May 21 12:50:14 2024 [pid 254883] [demo] DEBUG: Client "::ffff:217.82.60.116", "SSL shutdown state is: NONE"
Tue May 21 12:50:14 2024 [pid 254883] [demo] DEBUG: Client "::ffff:217.82.60.116", "SSL ret: 18446744073709551615, SSL error: error:0A000126:SSL routines::unexpected eof while reading, errno: 32"
Tue May 21 12:50:14 2024 [pid 254884] [demo] FAIL UPLOAD: Client "::ffff:217.82.60.116", "/home/demo/test-curl.txt", 0.00Kbyte/sec

@blach
Copy link
Author

blach commented May 21, 2024 •
edited

When I run the command successfully on the server itself, I get this instead:

Tue May 21 12:57:37 2024 [pid 254977] CONNECT: Client "::ffff:xx.xxx.xxx.xxx"
Tue May 21 12:57:37 2024 [pid 254977] DEBUG: Client "::ffff:xx.xxx.xxx.xxx", "SSL version: TLSv1.3, SSL cipher: TLS_AES_256_GCM_SHA384, not reused, no cert"
Tue May 21 12:57:37 2024 [pid 254976] [demo] OK LOGIN: Client "::ffff:xx.xxx.xxx.xxx"
Tue May 21 12:57:37 2024 [pid 254977] [demo] DEBUG: Client "::ffff:xx.xxx.xxx.xxx", "SSL version: TLSv1.3, SSL cipher: TLS_AES_256_GCM_SHA384, reused, no cert"
Tue May 21 12:57:37 2024 [pid 254977] [demo] DEBUG: Client "::ffff:xx.xxx.xxx.xxx", "SSL shutdown state is: SSL_RECEIVED_SHUTDOWN"
Tue May 21 12:57:37 2024 [pid 254977] [demo] DEBUG: Client "::ffff:xx.xxx.xxx.xxx", "SSL shutdown state is: 3"
Tue May 21 12:57:37 2024 [pid 254978] [demo] OK UPLOAD: Client "::ffff:xx.xxx.xxx.xxx", "/home/demo/test-curl.txt", 18432 bytes, 817.96Kbyte/sec

So it's indeed a problem with the SSL shutdown not working correctly when uploading from my Mac.

@jay
Copy link
Member

jay commented May 22, 2024 •
edited

#6149 sounds similar and my conclusion there was basically for each connection we need a separate optional state to do a proper SSL shutdown if the user specifies it or it's required because the server does not send the final message like for ftps data conn

see also https://curl.se/docs/knownbugs.html#FTPS_upload_data_loss_with_TLS_1

bagder pushed a commit that referenced this issue May 22, 2024
@icing @bagder
pytest: add ftp upload tests
5a913d8 
- refs #13556
- allow anon uploads on vsftpd test server
- add test_30_05 for plain upload of 1k, 100k, 1m
- add test_31_05 for SSL upload of 1k, 100k, 1m
- verify file size and contents

Closes #13734
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
FTP TLS
Milestone
No milestone
Development

No branches or pull requests
4 participants
@icing @bagder @jay @blach